Skip to content

Split the system tests log file into stages#801

Open
PranjalManhgaye wants to merge 12 commits into
precice:developfrom
PranjalManhgaye:issue-790-system-tests-logs
Open

Split the system tests log file into stages#801
PranjalManhgaye wants to merge 12 commits into
precice:developfrom
PranjalManhgaye:issue-790-system-tests-logs

Conversation

@PranjalManhgaye
Copy link
Copy Markdown
Collaborator

@PranjalManhgaye PranjalManhgaye commented May 27, 2026

Description

Fixes #790.
Right now, system-tests-stdout.log and system-tests-stderr.log only appear after a test finishes, which makes it hard to inspect failures during long Docker builds or solver runs.
This PR changes the logging so output is written to disk while the test is running. The existing combined logs are still kept, but there are now also separate phase logs:

  • system-tests-build.log
  • system-tests-solver.log
  • system-tests-fieldcompare.log

Scope: 4 files only (~350 LOC). No tutorial or reference-result changes.
Largest change: streaming Docker output in Systemtest.py (replaces communicate() buffering).
I also cleaned up the console output a bit:

  • [n/m] progress prefix
  • less noisy logging (INFO: removed)
  • clearer grouping/banners
  • PASS / FAIL markers on TTY
    The PR is split into 4 commits so the logging change can be reviewed separately from the console formatting cleanup.

Checklist

  • I added a summary of any user-facing changes (compared to the last release) in the changelog-entries/<PRnumber>.md.

Resources

Write build, solver, and fieldcompare output incrementally to
system-tests-stdout.log and system-tests-stderr.log, and add phase
logs (system-tests-build.log, -solver.log, -fieldcompare.log) so
failures can be debugged before a test finishes. Extend CI artifact
globs for the new log files.

Fixes the log-file part of precice#790.
Drop INFO prefix on routine log lines, put test index at the start of
start/finish messages, and add blank lines between tests for easier
scanning in CI and local runs.

Addresses the console formatting part of precice#790.
@PranjalManhgaye
Copy link
Copy Markdown
Collaborator Author

PranjalManhgaye commented May 27, 2026

passed (17/17), but the console output still looks like the old style, is this workflow expected to run with develop runner scripts, so formatting changes from this PR may not appear there?

@MakisH
Copy link
Copy Markdown
Member

MakisH commented May 27, 2026

@PranjalManhgaye I am not sure if this is currently documented (please check), but the trigger-system-tests does not take the tools/tests/ from the PR branch. This is often misleading when testing changes to the system tests scripts.

By the way, I think this PR can use a more descriptive title. How about "Split the system tests log file into stages"?

Do not forget to update the documentation and the hints in the workflow files (look for the original file name).

@PranjalManhgaye PranjalManhgaye changed the title Issue 790 system tests logs Split the system tests log file into stages May 27, 2026
Document combined and per-stage system test logs in README and job summary hints, and clarify workflow artifact step names to reflect staged log files.
@PranjalManhgaye PranjalManhgaye requested a review from MakisH May 31, 2026 09:44
Copy link
Copy Markdown
Member

@MakisH MakisH left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice job!

Running locally, I get the following example output (plus the respective files):

$ python systemtests.py --suites="elastic-tube-1d" --build_args="TUTORIALS_REF:develop,PYTHON_BINDINGS_REF:develop"

Using log-level: INFO
WARNING: No argument provided for needed parameter PRECICE_REF. Substituting with main
WARNING: No argument provided for needed parameter PLATFORM. Substituting with ubuntu_2404
WARNING: No argument provided for needed parameter PRECICE_PRESET. Substituting with production-audit
About to run 5 systemtest(s) in the directory /home/gc/repos/precice/tutorials/runs:
 [Elastic tube 1D (fluid-cpp, solid-cpp), Elastic tube 1D (fluid-cpp, solid-python), Elastic tube 1D (fluid-fortran, solid-fortran), Elastic tube 1D (fluid-fortran-module, solid-fortran-module), Elastic tube 1D (fluid-python, solid-python)]

================================================================================
[1/5] Started Elastic tube 1D (fluid-cpp, solid-cpp)
From github.com:PranjalManhgaye/tutorials
 * branch              issue-790-system-tests-logs -> FETCH_HEAD
Docker compose build for Elastic tube 1D (fluid-cpp, solid-cpp)
Docker compose solver for Elastic tube 1D (fluid-cpp, solid-cpp)
Docker compose fieldcompare for Elastic tube 1D (fluid-cpp, solid-cpp)
[1/5] Finished Elastic tube 1D (fluid-cpp, solid-cpp) in 24.5s [✅ PASS]
================================================================================

================================================================================
[2/5] Started Elastic tube 1D (fluid-cpp, solid-python)
From github.com:PranjalManhgaye/tutorials
 * branch              issue-790-system-tests-logs -> FETCH_HEAD
Overwrote <max-time> to 0.1 in /home/gc/repos/precice/tutorials/runs/elastic-tube-1d_fluid-cpp-solid-python_2026-05-31-230350/precice-config.xml
Docker compose build for Elastic tube 1D (fluid-cpp, solid-python)
Docker compose solver for Elastic tube 1D (fluid-cpp, solid-python)
CRITICAL: Systemtest Elastic tube 1D (fluid-cpp, solid-python) timed out during docker compose solver after 900s. Killing the process.
CRITICAL: Could not run the tutorial, Elastic tube 1D (fluid-cpp, solid-python) failed
[2/5] Finished Elastic tube 1D (fluid-cpp, solid-python) in 957.6s [❌ FAIL]
================================================================================

================================================================================
[3/5] Started Elastic tube 1D (fluid-fortran, solid-fortran)
From github.com:PranjalManhgaye/tutorials
 * branch              issue-790-system-tests-logs -> FETCH_HEAD
Docker compose build for Elastic tube 1D (fluid-fortran, solid-fortran)
Docker compose solver for Elastic tube 1D (fluid-fortran, solid-fortran)
Docker compose fieldcompare for Elastic tube 1D (fluid-fortran, solid-fortran)
[3/5] Finished Elastic tube 1D (fluid-fortran, solid-fortran) in 20.6s [✅ PASS]
================================================================================

================================================================================
[4/5] Started Elastic tube 1D (fluid-fortran-module, solid-fortran-module)
From github.com:PranjalManhgaye/tutorials
 * branch              issue-790-system-tests-logs -> FETCH_HEAD
Docker compose build for Elastic tube 1D (fluid-fortran-module, solid-fortran-module)
Docker compose solver for Elastic tube 1D (fluid-fortran-module, solid-fortran-module)
Docker compose fieldcompare for Elastic tube 1D (fluid-fortran-module, solid-fortran-module)
[4/5] Finished Elastic tube 1D (fluid-fortran-module, solid-fortran-module) in 26.1s [✅ PASS]
================================================================================

================================================================================
[5/5] Started Elastic tube 1D (fluid-python, solid-python)
From github.com:PranjalManhgaye/tutorials
 * branch              issue-790-system-tests-logs -> FETCH_HEAD
Docker compose build for Elastic tube 1D (fluid-python, solid-python)
Docker compose solver for Elastic tube 1D (fluid-python, solid-python)
Docker compose fieldcompare for Elastic tube 1D (fluid-python, solid-python)
CRITICAL: Fieldcompare returned non zero exit code, therefore Elastic tube 1D (fluid-python, solid-python) failed
[5/5] Finished Elastic tube 1D (fluid-python, solid-python) in 12.2s [❌ FAIL]
================================================================================

Success running Elastic tube 1D (fluid-cpp, solid-cpp)
ERROR: Failed to run Elastic tube 1D (fluid-cpp, solid-python)
Success running Elastic tube 1D (fluid-fortran, solid-fortran)
Success running Elastic tube 1D (fluid-fortran-module, solid-fortran-module)
ERROR: Failed to run Elastic tube 1D (fluid-python, solid-python)
+----------------------------------------------------------------+---------+-------------------+-----------------+-----------------------+
| systemtest                                                     | success | building time [s] | solver time [s] | fieldcompare time [s] |
+----------------------------------------------------------------+---------+-------------------+-----------------+-----------------------+
| Elastic tube 1D (fluid-cpp, solid-cpp)                         |    1    |        0.5        |      14.9       |          5.6          |
+----------------------------------------------------------------+---------+-------------------+-----------------+-----------------------+
| Elastic tube 1D (fluid-cpp, solid-python)                      |    0    |       43.7        |      910.2      |          0.0          |
+----------------------------------------------------------------+---------+-------------------+-----------------+-----------------------+
| Elastic tube 1D (fluid-fortran, solid-fortran)                 |    1    |        0.4        |      10.2       |          6.6          |
+----------------------------------------------------------------+---------+-------------------+-----------------+-----------------------+
| Elastic tube 1D (fluid-fortran-module, solid-fortran-module)   |    1    |        1.1        |      14.1       |          4.8          |
+----------------------------------------------------------------+---------+-------------------+-----------------+-----------------------+
| Elastic tube 1D (fluid-python, solid-python)                   |    0    |        1.3        |       4.4       |          2.5          |
+----------------------------------------------------------------+---------+-------------------+-----------------+-----------------------+

Since you are touching the general formatting of the logs:

  • For the header, I think that listing the tests to run as an enumeration would be useful to vertically scan them.
  • I would also display the test suites to run.
  • Before the summary table, I would leave an empty line.

Suggested format (the argument warnings depend on the tests to run):

Selected test suite(s):

- elastic-tube-1d

About to run 5 test(s) in the directory /home/gc/repos/precice/tutorials/runs:

1. Elastic tube 1D (fluid-cpp, solid-cpp)
2. Elastic tube 1D (fluid-cpp, solid-python)
3. Elastic tube 1D (fluid-fortran, solid-fortran)
4. Elastic tube 1D (fluid-fortran-module, solid-fortran-module)
5. Elastic tube 1D (fluid-python, solid-python)]

WARNING: No argument provided for needed parameter PRECICE_REF. Substituting with main
WARNING: No argument provided for needed parameter PLATFORM. Substituting with ubuntu_2404
WARNING: No argument provided for needed parameter PRECICE_PRESET. Substituting with production-audit
Using log-level: INFO

I also tested this on GitHub Actions, here: https://github.com/precice/tutorials/actions/runs/26725804527

Comment thread .github/workflows/generate_reference_results_workflow.yml Outdated
Comment thread .github/workflows/run_testsuite_workflow.yml Outdated
Comment thread changelog-entries/801.md Outdated
Comment thread tools/tests/systemtests/Systemtest.py Outdated
Comment thread tools/tests/systemtests.py Outdated
Comment thread tools/tests/systemtests/Systemtest.py
Comment thread tools/tests/systemtests.py Outdated
Comment thread tools/tests/systemtests.py
Comment thread tools/tests/systemtests.py Outdated
Comment thread tools/tests/systemtests.py Outdated
Comment thread tools/tests/systemtests.py
Comment thread tools/tests/systemtests.py
Print PASS/FAIL after ::endgroup:: so results stay visible when groups
are collapsed, add a blank line before the per-test summary, and show
status symbols in the results table and job summary.
@PranjalManhgaye PranjalManhgaye requested a review from MakisH June 1, 2026 13:20
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In the latest run, the groups worked nicely. However, the newlines are now gone; these were useful.

Image

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ohh thanks i restored those blank lines

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It also looks like all groups are expanded by default now.

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

do you mean the whole log opens unfolded after the job finishes? I don’t think we can force collapsed groups from systemtests.py

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i added blank lines after each test in 2bacf6f, but they still don’t show clearly in your run ,do you see no blank lines at all, or just not enough when the groups are expanded? , Should we add more blank lines between tests, or would you prefer a different separator than the old ==== banners?

Add an empty line after each test's PASS/FAIL output so logs stay
readable now that === banners are removed.
@PranjalManhgaye PranjalManhgaye requested a review from MakisH June 1, 2026 13:48
PranjalManhgaye added a commit to PranjalManhgaye/tutorials that referenced this pull request Jun 1, 2026
Link the pull request instead of the issue and keep the entry short.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

System tests logs appear only at the end

2 participants